**** dT    0.000
*    top   TEST ../../../../bin/varnishtest/tests/b00020.vtc starting
**** top   extmacro def pkg_version=trunk
**** top   extmacro def pkg_branch=trunk
**** top   extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:36721
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top   extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../..
**** top   macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top   macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589
**** top   macro def vtcid=vtc.3004285.4a7a2589
**   top   === varnishtest "Check that between_bytes_timeout behaves from p...
*    top   VTEST Check that between_bytes_timeout behaves from parameters
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=38201
**** s1    macro def s1_sock=127.0.0.1:38201
*    s1    Listen on 127.0.0.1:38201
**   top   === varnish v1 -vcl+backend {
**** dT    0.003
**   s1    Started on 127.0.0.1:38201 (1 iterations)
**** dT    0.015
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 41915' -P /home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 41915' -P /home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    PID: 3004304
**** v1    macro def v1_pid=3004304
**** v1    macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.3004285.4a7a2589/v1
**** dT    0.020
***  v1    debug|Info: Working directory not mounted on tmpfs partition
***  v1    debug|
**** dT    0.146
***  v1    debug|Debug: Version: varnish-trunk revision a34ea21b5e8e9dbac4e04f333404d3c791932e49
***  v1    debug|Debug: Platform: Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 329     
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-trunk revision a34ea21b5e8e9dbac4e04f333404d3c791932e49
***  v1    debug|
***  v1    debug|Type 'help' for command list.
***  v1    debug|Type 'quit' to close CLI session.
***  v1    debug|Type 'start' to launch worker process.
***  v1    debug|
**** dT    0.151
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
***  v1    CLI RX  107
**** v1    CLI RX|zybzcscplozhlruanhjrlodzglqakdhh
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** dT    0.152
**** v1    CLI TX|auth ff870bd61447c11c3265d0d43a74bc7db87d992443f21120c0ddda201c15a42c
**** dT    0.158
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-trunk revision a34ea21b5e8e9dbac4e04f333404d3c791932e49
**** v1    CLI RX|
**** v1    CLI RX|Type 'help' for command list.
**** v1    CLI RX|Type 'quit' to close CLI session.
**** v1    CLI RX|Type 'start' to launch worker process.
**** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "38201"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tset beresp.do_stream = false;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.263
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.363
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.465
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.566
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.669
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.771
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.872
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.976
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.000
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
**** dT    1.007
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    1.057
***  v1    debug|Debug: Child (3004317) Started
**** dT    1.079
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.125
***  v1    debug|Child launched OK
**** dT    1.151
***  v1    debug|Info: Child (3004317) said Child starts
**** dT    1.152
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
**** dT    1.157
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
**** dT    1.182
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1745603789.156293/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1745603789.156293/vgc.so" as "vcl1"
**** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|          0 CLI             - Rd start
**** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:44527
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:44527
**** v1    vsl|          0 CLI             - Wr 200 0 
**** dT    1.205
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44527
**** v1    CLI TX|debug.xid 1000
**** dT    1.285
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44527

**** dT    1.524
***  v1    CLI RX  200
**** v1    CLI RX|XID is 1000 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    1.606
**** v1    vsl|          0 CLI             - Rd debug.xid 1000 
**** v1    vsl|          0 CLI             - Wr 200 19 XID is 1000 chunk 1
**** dT    2.118
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44527

**** dT    3.289
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44527
**   v1    Listen on 127.0.0.1 44527
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=44527
**** v1    macro def v1_sock=127.0.0.1:44527
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=44527
**** v1    macro def v1_a0_sock=127.0.0.1:44527
**   top   === varnish v1 -cliok "param.set between_bytes_timeout 1"
**** v1    CLI TX|param.set between_bytes_timeout 1
**** dT    4.161
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1745603793 1.0
**** dT    4.206
***  v1    CLI RX  200
**   v1    CLI 200 <param.set between_bytes_timeout 1>
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    4.207
**   c1    Started on 127.0.0.1:44527 (1 iterations)
***  c1    Connect to 127.0.0.1:44527
**** dT    4.208
***  c1    connected fd 17 from 127.0.0.1 60252 to 127.0.0.1:44527
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|User-Agent: c1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    4.605
***  s1    accepted fd 5 127.0.0.1 48072
**   s1    === rxreq
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|User-Agent: c1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |User-Agent: c1
**** s1    http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 7] |Accept-Encoding: gzip
**** s1    http[ 8] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === send "HTTP/1.0 200 OK\r\nConnection: close\r\n\r\n"
**** s1    send|HTTP/1.0 200 OK\r
**** s1    send|Connection: close\r
**** s1    send|\r
**   s1    === delay 1.5
***  s1    delaying 1.5 second(s)
**** dT    4.670
**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 60252 a0 127.0.0.1 44527 1745603793.599169 22
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** dT    5.691
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1745603793.599375 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b User-Agent: c1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1002 VCL_return      b fetch
**** v1    vsl|       1002 Timestamp       b Fetch: 1745603793.599406 0.000030 0.000030
**** v1    vsl|       1002 Timestamp       b Connected: 1745603793.599557 0.000182 0.000151
**** v1    vsl|       1002 BackendOpen     b 25 s1 127.0.0.1 38201 127.0.0.1 48072 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1745603793.599596 0.000221 0.000039
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.0
**** v1    vsl|       1002 BerespStatus    b 200
**** v1    vsl|       1002 BerespReason    b OK
**** v1    vsl|       1002 BerespHeader    b Connection: close
**** v1    vsl|       1002 Timestamp       b Beresp: 1745603793.604877 0.005502 0.005280
**** v1    vsl|       1002 BerespHeader    b Date: Fri, 25 Apr 2025 17:56:33 GMT
**** v1    vsl|       1002 TTL             b RFC 120 10 0 1745603794 1745603794 1745603793 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Debug           b Missing content-range header or unknown range unit
**** v1    vsl|       1002 Timestamp       b Process: 1745603793.604962 0.005587 0.000085
**** v1    vsl|       1002 Filters         b 
**** v1    vsl|       1002 Storage         b malloc s0
**** v1    vsl|       1002 Fetch_Body      b 4 eof -
**** v1    vsl|       1002 FetchError      b Resource temporarily unavailable
**** v1    vsl|       1002 FetchError      b eof socket fail
**** v1    vsl|       1002 BackendClose    b 25 s1 close RX_BODY
**** v1    vsl|       1002 Timestamp       b Error: 1745603794.680022 1.080646 1.075059
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 503
**** v1    vsl|       1002 BerespReason    b Backend fetch failed
**** v1    vsl|       1002 BerespHeader    b Date: Fri, 25 Apr 2025 17:56:34 GMT
**** v1    vsl|       1002 BerespHeader    b Server: Varnish
**** v1    vsl|       1002 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1002 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v1    vsl|       1002 BerespHeader    b Retry-After: 5
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Storage         b malloc Transient
**** v1    vsl|       1002 Length          b 281
**** v1    vsl|       1002 BereqAcct       b 148 0 148 38 0 38
**** v1    vsl|       1002 End             b 
**** dT    5.867
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Date: Fri, 25 Apr 2025 17:56:34 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Content-Length: 281\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 246
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Date: Fri, 25 Apr 2025 17:56:34 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |Content-Type: text/html; charset=utf-8
**** c1    http[ 6] |Retry-After: 5
**** c1    http[ 7] |X-Varnish: 1001
**** c1    http[ 8] |Age: 0
**** dT    5.868
**** c1    http[ 9] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[10] |Content-Length: 281
**** c1    http[11] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1002</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 281
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
***  c1    closing fd 17
**   c1    Ending
**** dT    5.894
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1745603793.599232 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1745603793.599232 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 60252 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c User-Agent: c1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 VCL_return      c hash
**** v1    vsl|       1001 VCL_call        c HASH
**** v1    vsl|       1001 VCL_return      c lookup
**** v1    vsl|       1001 VCL_call        c MISS
**** v1    vsl|       1001 VCL_return      c fetch
**** v1    vsl|       1001 Link            c bereq 1002 fetch
**** v1    vsl|       1001 Timestamp       c Fetch: 1745603794.859084 1.259852 1.259852
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 503
**** v1    vsl|       1001 RespReason      c Backend fetch failed
**** v1    vsl|       1001 RespHeader      c Date: Fri, 25 Apr 2025 17:56:34 GMT
**** v1    vsl|       1001 RespHeader      c Server: Varnish
**** v1    vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1001 RespHeader      c Retry-After: 5
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1001 VCL_call        c DELIVER
**** v1    vsl|       1001 VCL_return      c deliver
**** v1    vsl|       1001 Timestamp       c Process: 1745603794.859166 1.259934 0.000082
**** v1    vsl|       1001 Filters         c 
**** v1    vsl|       1001 RespHeader      c Content-Length: 281
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 Timestamp       c Resp: 1745603794.859248 1.260016 0.000081
**** v1    vsl|       1001 ReqAcct         c 51 0 51 246 281 527
**** v1    vsl|       1001 End             c 
**** dT    5.995
**   top   === delay 1
***  top   delaying 1 second(s)
**** dT    5.996
**** v1    vsl|       1000 SessClose       c REM_CLOSE 1.392
**** v1    vsl|       1000 End             c 
**** dT    6.106
***  s1    shutting fd 5
**   s1    Ending
**** dT    7.092
**   top   === varnish v1 -expect n_object == 0
**   v1    as expected: n_object (0) == 0 (0)
**   top   === varnish v1 -expect n_objectcore == 0
**   v1    as expected: n_objectcore (0) == 0 (0)
**   top   === server s1 -wait {
**   s1    Waiting for server (4/-1)
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=38201
**** s1    macro def s1_sock=127.0.0.1:38201
*    s1    Listen on 127.0.0.1:38201
**** dT    7.093
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   s1    Started on 127.0.0.1:38201 (1 iterations)
**** dT    7.097
**   c1    Started on 127.0.0.1:44527 (1 iterations)
***  c1    Connect to 127.0.0.1:44527
***  c1    connected fd 19 from 127.0.0.1 60266 to 127.0.0.1:44527
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|User-Agent: c1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    7.099
***  s1    accepted fd 18 127.0.0.1 48080
**   s1    === non_fatal
**   s1    === rxreq
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|User-Agent: c1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1005\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |User-Agent: c1
**** s1    http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 7] |Accept-Encoding: gzip
**** s1    http[ 8] |X-Varnish: 1005
**** s1    bodylen = 0
**   s1    === send "HTTP/1.0 200 OK\r\nConnection: close\r\n\r\n"
**** s1    send|HTTP/1.0 200 OK\r
**** s1    send|Connection: close\r
**** s1    send|\r
**   s1    === delay 0.5
***  s1    delaying 0.5 second(s)
**** dT    7.130
**** v1    vsl|       1003 Begin           c sess 0 HTTP/1
**** v1    vsl|       1003 SessOpen        c 127.0.0.1 60266 a0 127.0.0.1 44527 1745603796.094325 24
**** v1    vsl|       1003 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:44527
**** v1    vsl|       1003 Link            c req 1004 rxreq
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1745603796 1.0
**** dT    7.666
**   s1    === send "Baba\n"
**** s1    send|Baba
**   s1    === delay 0.5
***  s1    delaying 0.5 second(s)
**** dT    8.810
**   s1    === send "Baba\n"
**** s1    send|Baba
***  s1    shutting fd 18
**** dT    8.811
**   s1    Ending
**** dT    8.812
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Date: Fri, 25 Apr 2025 17:56:37 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|X-Varnish: 1004\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Content-Length: 281\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 246
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Date: Fri, 25 Apr 2025 17:56:37 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |Content-Type: text/html; charset=utf-8
**** c1    http[ 6] |Retry-After: 5
**** c1    http[ 7] |X-Varnish: 1004
**** c1    http[ 8] |Age: 0
**** c1    http[ 9] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[10] |Content-Length: 281
**** c1    http[11] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1005</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 281
**   c1    === expect resp.status == 200
---- c1    EXPECT resp.status (503) == "200" failed
**** dT    8.814
*    top   RESETTING after ../../../../bin/varnishtest/tests/b00020.vtc
**   s1    Waiting for server (4/-1)
**   v1    Wait
**** v1    CLI TX|panic.show
**** dT    8.832
**** v1    vsl|       1005 Begin           b bereq 1004 fetch
**** v1    vsl|       1005 VCL_use         b vcl1
**** v1    vsl|       1005 Timestamp       b Start: 1745603796.094533 0.000000 0.000000
**** v1    vsl|       1005 BereqMethod     b GET
**** v1    vsl|       1005 BereqURL        b /
**** v1    vsl|       1005 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1005 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b User-Agent: c1
**** v1    vsl|       1005 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1005 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1005 BereqHeader     b X-Varnish: 1005
**** v1    vsl|       1005 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1005 VCL_return      b fetch
**** v1    vsl|       1005 Timestamp       b Fetch: 1745603796.094656 0.000123 0.000123
**** v1    vsl|       1005 Timestamp       b Connected: 1745603796.094696 0.000162 0.000039
**** v1    vsl|       1005 BackendOpen     b 25 s1 127.0.0.1 38201 127.0.0.1 48080 connect
**** v1    vsl|       1005 Timestamp       b Bereq: 1745603796.094728 0.000195 0.000032
**** v1    vsl|       1005 BerespProtocol  b HTTP/1.0
**** v1    vsl|       1005 BerespStatus    b 200
**** v1    vsl|       1005 BerespReason    b OK
**** v1    vsl|       1005 BerespHeader    b Connection: close
**** v1    vsl|       1005 Timestamp       b Beresp: 1745603796.095590 0.001056 0.000861
**** v1    vsl|       1005 BerespHeader    b Date: Fri, 25 Apr 2025 17:56:36 GMT
**** v1    vsl|       1005 TTL             b RFC 120 10 0 1745603796 1745603796 1745603796 0 0 cacheable
**** v1    vsl|       1005 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1005 VCL_return      b deliver
**** v1    vsl|       1005 Debug           b Missing content-range header or unknown range unit
**** v1    vsl|       1005 Timestamp       b Process: 1745603796.095613 0.001080 0.000023
**** v1    vsl|       1005 Filters         b 
**** v1    vsl|       1005 Storage         b malloc s0
**** v1    vsl|       1005 Fetch_Body      b 4 eof -
**** v1    vsl|       1005 FetchError      b Resource temporarily unavailable
**** v1    vsl|       1005 FetchError      b eof socket fail
**** v1    vsl|       1005 BackendClose    b 25 s1 close RX_BODY
**** v1    vsl|       1005 Timestamp       b Error: 1745603797.726853 1.632320 1.631239
**** v1    vsl|       1005 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1005 BerespStatus    b 503
**** v1    vsl|       1005 BerespReason    b Backend fetch failed
**** v1    vsl|       1005 BerespHeader    b Date: Fri, 25 Apr 2025 17:56:37 GMT
**** v1    vsl|       1005 BerespHeader    b Server: Varnish
**** v1    vsl|       1005 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1005 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v1    vsl|       1005 BerespHeader    b Retry-After: 5
**** v1    vsl|       1005 VCL_return      b deliver
**** v1    vsl|       1005 Storage         b malloc Transient
**** v1    vsl|       1005 Length          b 281
**** v1    vsl|       1005 BereqAcct       b 148 0 148 38 5 43
**** v1    vsl|       1005 End             b 
**** v1    vsl|       1004 Begin           c req 1003 rxreq
**** v1    vsl|       1004 Timestamp       c Start: 1745603796.094368 0.000000 0.000000
**** v1    vsl|       1004 Timestamp       c Req: 1745603796.094368 0.000000 0.000000
**** v1    vsl|       1004 VCL_use         c vcl1
**** v1    vsl|       1004 ReqStart        c 127.0.0.1 60266 a0
**** v1    vsl|       1004 ReqMethod       c GET
**** v1    vsl|       1004 ReqURL          c /
**** v1    vsl|       1004 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1004 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1004 ReqHeader       c User-Agent: c1
**** v1    vsl|       1004 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1004 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1004 VCL_call        c RECV
**** v1    vsl|       1004 VCL_return      c hash
**** v1    vsl|       1004 VCL_call        c HASH
**** v1    vsl|       1004 VCL_return      c lookup
**** v1    vsl|       1004 VCL_call        c MISS
**** v1    vsl|       1004 VCL_return      c fetch
**** v1    vsl|       1004 Link            c bereq 1005 fetch
**** v1    vsl|       1004 Timestamp       c Fetch: 1745603797.727056 1.632687 1.632687
**** v1    vsl|       1004 RespProtocol    c HTTP/1.1
**** v1    vsl|       1004 RespStatus      c 503
**** v1    vsl|       1004 RespReason      c Backend fetch failed
**** v1    vsl|       1004 RespHeader      c Date: Fri, 25 Apr 2025 17:56:37 GMT
**** v1    vsl|       1004 RespHeader      c Server: Varnish
**** v1    vsl|       1004 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1004 RespHeader      c Retry-After: 5
**** v1    vsl|       1004 RespHeader      c X-Varnish: 1004
**** v1    vsl|       1004 RespHeader      c Age: 0
**** v1    vsl|       1004 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1004 VCL_call        c DELIVER
**** v1    vsl|       1004 VCL_return      c deliver
**** v1    vsl|       1004 Timestamp       c Process: 1745603797.727084 1.632715 0.000028
**** v1    vsl|       1004 Filters         c 
**** v1    vsl|       1004 RespHeader      c Content-Length: 281
**** v1    vsl|       1004 RespHeader      c Connection: keep-alive
**** v1    vsl|       1004 Timestamp       c Resp: 1745603797.727133 1.632765 0.000049
**** v1    vsl|       1004 ReqAcct         c 51 0 51 246 281 527
**** v1    vsl|       1004 End             c 
**** dT    8.862
***  v1    CLI RX  300
**** v1    CLI RX|Child has not panicked or panic has been cleared
**** dT    8.863
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    8.937
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    8.963
***  v1    debug|Info: Child (3004317) said Child dies
**** dT    9.677
***  v1    debug|Info: Child (3004317) ended
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** v1    STDOUT EOF
**** dT    9.756
**   v1    WAIT4 pid=3004304 status=0x0000 (user 0.235717 sys 0.035101)
**** dT    9.757
*    top   TEST ../../../../bin/varnishtest/tests/b00020.vtc FAILED
#    top  TEST ../../../../bin/varnishtest/tests/b00020.vtc FAILED (9.757) exit=2
FAIL tests/b00020.vtc (exit status: 2)